DIRMINA-1199 - race condition when sending multiple larger data chunks - #77

I have applied your patch, and tested it with Thomas's test: it's still failing.

The synchronized queue (for instance mReceiveQueue) must also be synchronized where it is used (like in the receive_loop method) in all the class, otherwise it will not be very useful (FTR, I have added such synchronized section everywhere the mReceiveQueue and mWritingQueue are used, it does not help

Interesting. Let me check.

Are you sure about this? I just run the test attached to JIRA 20 times and it didn't fail. Test must throw exception to fail, error logs are just for logging and not changing log4j config.

I can merge Thomas's test in this PR. Should I?

Ah my bad, I applied the patch in a MINA code base that is not the one that contains the test...

Let me reapply it at the right place and restest it.

Ok, once applied, Thomas' test is green. (actually, adding the synchronized on mWriteQueue is enough).

Still this is mysterious why this synchronized bit is necessary. The SSL Filter will be executed on one single thread, where the second thread accessing this queue is coming from?

forward_writes is also called in several unsynchronized methods: ack, close, flush, open, receive.

A test for the fix should also be bidirectional: the server should send back some reply on a message reception and the client should read that reply.

A test for the fix should also be bidirectional: the server should send back some reply on a message reception and the client should read that reply.

I will add this. Probably not today.

Still this is mysterious why this synchronized bit is necessary. The SSL Filter will be executed on one single thread, where the second thread accessing this queue is coming from?

The logging for forward received is put in the bad spot. I will improve this.

[13:01:35] [NioProcessor-138] DEBUG org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@5b867368[mode=server, connected=false] forward_received()
[13:01:26] [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@61e56151[mode=server, connected=true] forward_received()

The two SslHandler instances are different instances (@5b867368 and @61e56151).
More important, the mWriteQueue is not a static instance, each SslHandler instance have its own queue, so there is no chance those two threads might stamp on each other data, AFAICT.

So the Synchronized(mWriteQueue) 'fixes' the issue but I don't understand how...
Or maybe I'm brain dead and I'm missing something obvious ;-)

I had Claude look into it and provided some background.

Root cause / history

The synchronized (queue) blocks around the drain loops were part of the original G1 design. From the description of #44:

The code which pulls objects out of this Queue is blocked by itself so no two threads can be pulling from the Queue concurrently.

They were commented out in 62643fe ("alright lets remove all the synchronization from the queue flushes"). That was an experiment on the in-progress bugfix/DIRMINA-1173 branch. I never meant it to be merged. The branch was later merged into 2.2.X together with unrelated maintenance work, so the experiment shipped in 2.2.4. This PR restores the intended design.

Why mWriteQueue is the one that matters

Encryption happens under the handler monitor, so records go into mWriteQueue in the correct order. The drain runs after the monitor is released, though, and it's reached from several threads at once:

• the application thread: write() → forward_writes
• the IO processor thread: ack() → flush_start (which encrypts more queued chunks because of MAX_UNACK_MESSAGES) → forward_writes
• the receive path: receive() → forward_writes

If two threads poll consecutive records and reach filterWrite in the opposite order, the records go out of order on the wire. TLS sequence numbers are implicit, so the peer fails with bad_record_mac or corrupted data. Large messages split into several records make this much more likely. That fits @elecharny's observation that locking mWriteQueue alone makes the test pass.

mReceiveQueue needs the same protection. receive() normally runs on one IO thread per session, but a thread-dispatching filter can be placed in front of SslFilter. Decryption in receive_start is serialized by the handler monitor, but forward_received drains after that monitor is released. Without the lock, one thread can still be delivering its decrypted buffers while another decrypts the next message and drains too, and the application receives the plaintext out of order. mEventQueue is exposed the same way. All three locks belong to the original design and should stay.

Requested changes

1. Debug logging: please drop the new entry logs in forward_*(). They add 2–3 lines per event and don't say much. The existing per-item logs are enough.
2. SslFilterTest:
   • The 61000–80000 loop is ~19k round trips, which is too slow for the regular build. A handful of sizes around the record/packet boundaries should be enough.
   • CompareFilter only logs on a data mismatch and then counts down the latch, so corrupted data doesn't fail the test. Please record it as a failure (e.g. set failure) so the assertion catches it.
   • Progress is logged at ERROR level; please use DEBUG.
   • Missing newline at end of file.
3. SslEnd2EndTest is bidirectional and asserts the content, which covers what was asked for earlier. If it reproduces the failure reliably without the fix, I'd be fine keeping only this one.

+1 on the fix itself once the tests are cleaned up.

Hi Jon, long time no see ;-)

I buy what Claude says.

Still I'm having hard time understanding how 2 different threads could concurrently access the same queue when each thread uses a different SslHandler instance, each one with its own instance of a queue, so there is no way one queue can be shared between those two threads...

@elecharny

The two SslHandler instances are different instances (@5b867368 and @61e56151).
More important, the mWriteQueue is not a static instance, each SslHandler instance have its own queue, so there is no chance those two threads might stamp on each other data, AFAICT.

You are right and now I am confused. I did some grepping and I don't see them interleaving in an obvious way. I will look tomorrow.

@jon-valliere
@elecharny

That fits @elecharny's observation that locking mWriteQueue alone makes the test pass.

After making the test bidirectional as suggested by Thomas - the acceptor sends the response back - the synchronization on mWriteQueue is also required. The test fails without it.

I removed SslFilterTest.java as it is not required. SslEnd2EndTest.java covers all cases, it is bidirectional and it is parametrized. I have a feeling that synchronized block is required for the mEventQueue, but this is based on a hunch.

Pushed latest changes with additional logging outside of synchronized blocks.

That is an interesting bug hunt ;-)

Hi Jon, long time no see ;-)

I buy what Claude says.

Still I'm having hard time understanding how 2 different threads could concurrently access the same queue when each thread uses a different SslHandler instance, each one with its own instance of a queue, so there is no way one queue can be shared between those two threads...

Which queue are you referring to? The queues are per connection/socket.

Going off memory here...

In HTTP/2 for example, the chunking + virtual channel mechanism could span multiple async requests in parallel on different threads with each thread submitting chunks/files into writer pipeline for a single socket. Mina does not guarantee any kind of ordering on the write pipeline and leaves it entirely up to your own implementation.

The synchronized monitors around the queues are necessary not because the queue is unsafe but because the pipeline function of polling from the queue and pushing into the connection/socket needs to be synchronized. To prevent write corruption, the order encrypted messages are pulled from the queue and written to the socket must be guaranteed.

Claude seems to be right. Write is the problem on the sender side. Processor competes with jUnit thread.

[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@5bda8e08[pos=0 lim=16405 cap=66836: 17 03 03 40 10 A8 B8 F2 E1 D2 8F A5 CF 73 08 9E]
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@1e800aaa[pos=0 lim=16405 cap=50127: 17 03 03 40 10 BD 1F 48 79 4D FF 26 65 53 43 F6]
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@185a6e9[pos=0 lim=16405 cap=33418: 17 03 03 40 10 BC 20 2B 64 4D CB 85 97 9A 6C 9F]
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@6f03482[pos=0 lim=16405 cap=33418: 17 03 03 40 10 E0 7B DF 3E 81 F7 D6 69 14 BF C5]
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@9d5509a[pos=0 lim=16405 cap=66836: 17 03 03 40 10 75 73 4C A8 92 6D E8 B5 6C 22 A4]
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@179ece50[pos=0 lim=16405 cap=50127: 17 03 03 40 10 B2 C3 B2 E9 FB 48 3A 72 9E 46 F1]
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@3b0090a4[pos=0 lim=16405 cap=33418: 17 03 03 40 10 40 11 93 E7 B0 19 41 14 94 B1 31]
[18:21:18] [main] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes() - writing WriteRequest: HeapBuffer@3cd3e762[pos=0 lim=16405 cap=33418: 17 03 03 40 10 93 AF 10 CE F7 93 00 9F 85 98 4A]
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()
[18:21:18] [NioProcessor-36] INFO org.apache.mina.filter.ssl.SslHandler - SSLHandlerG1@dbe2289[mode=client, connected=true] forward_writes()

@the-thing check my original PR #44 and the original commit before the experiment. I explained the reason for this design and drew a diagram in the description.

I had a look at the PR and it makes sense to me, but I clearly do not understand all the pieces. I'm not questioning the design, but I was more curious about the fact that at some point you decided to remove synchronized blocks from the code, but they were initially put in place, because you had a glimpse of failing scenarios.

They were commented out in 62643fe ("alright lets remove all the synchronization from the queue flushes"). That was an experiment on the in-progress bugfix/DIRMINA-1173 branch. I never meant it to be merged. The branch was later merged into 2.2.X together with unrelated maintenance work, so the experiment shipped in 2.2.4. This PR restores the intended design.

So the bottom line is that this particular commit should have stayed.

I had a look at the PR and it makes sense to me, but I clearly do not understand all the pieces. I'm not questioning the design, but I was more curious about the fact that at some point you decided to remove synchronized blocks from the code, but they were initially put in place, because you had a glimpse of failing scenarios.

They were commented out in 62643fe ("alright lets remove all the synchronization from the queue flushes"). That was an experiment on the in-progress bugfix/DIRMINA-1173 branch. I never meant it to be merged. The branch was later merged into 2.2.X together with unrelated maintenance work, so the experiment shipped in 2.2.4. This PR restores the intended design.

So the bottom line is that this particular commit should have stayed.

It should have been reverted. It was an experiment because I was on the email thread with someone who wanted to run tests with some harness they were unable to share with me. The literal // comment out is the giveaway it was not intended to be merged. Let's just call it a miscommunication.

Hi Jon, long time no see ;-)
I buy what Claude says.
Still I'm having hard time understanding how 2 different threads could concurrently access the same queue when each thread uses a different SslHandler instance, each one with its own instance of a queue, so there is no way one queue can be shared between those two threads...

Which queue are you referring to? The queues are per connection/socket.

The mWriteQueue.

Going off memory here...

In HTTP/2 for example, the chunking + virtual channel mechanism could span multiple async requests in parallel on different threads with each thread submitting chunks/files into writer pipeline for a single socket. Mina does not guarantee any kind of ordering on the write pipeline and leaves it entirely up to your own implementation.

Totally agree on this. My concern is for this specific test that demonstrates the issue: we have one connector sending a big message to one acceptor, and wait for the response. And still, we have two threads messing with the queue, which I don't understand.

The synchronized monitors around the queues are necessary not because the queue is unsafe but because the pipeline function of polling from the queue and pushing into the connection/socket needs to be synchronized. To prevent write corruption, the order encrypted messages are pulled from the queue and written to the socket must be guaranteed.

Agreed.

I had a look at the PR and it makes sense to me, but I clearly do not understand all the pieces. I'm not questioning the design, but I was more curious about the fact that at some point you decided to remove synchronized blocks from the code, but they were initially put in place, because you had a glimpse of failing scenarios.

They were commented out in 62643fe ("alright lets remove all the synchronization from the queue flushes"). That was an experiment on the in-progress bugfix/DIRMINA-1173 branch. I never meant it to be merged. The branch was later merged into 2.2.X together with unrelated maintenance work, so the experiment shipped in 2.2.4. This PR restores the intended design.

So the bottom line is that this particular commit should have stayed.

It should have been reverted. It was an experiment because I was on the email thread with someone who wanted to run tests with some harness they were unable to share with me. The literal // comment out is the giveaway it was not intended to be merged. Let's just call it a miscommunication.

I'm probably the one who merged the change into trunk by mistake. The mail, thread was off the dev mailing list, between Jon, me and two other people, and it was related to https://issues.apache.org/jira/browse/DIRMINA-1173.

@jon-valliere you wrote that:

"I’m still a little concerned about the additions I made. It is very much an experimental version which has to be enabled manually. The last commit I made makes it even more so. The original version, IMHO is very stable and safely designed."

and that was pretty much the last messages before your change gets merged into trunk by me in April, 18th 2024, pretty much 2 months after the mail discussion (and I most certainly merged for some other reason, having forgotten what it was all about).

At this point, I think we should revert the change, have the queues synchronized as it was before.

Still, I'm having hard time understanding how it solves the issue and have the test passing.

I'll have a 4 hours train trip this morning, I'll try to check the ins and outs of the issue, I'm very confused at this point...

Thanks @the-thing @tomaswolf and @jon-valliere for all your inputs!

Latest changes pushed as suggested.

With the current setup the build is significantly longer especially on Linux (these environment seem to have some problems in recent days as the delay to start seem to be longer)

{"TLSv1.2", "TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256", 2048, 0},
{"TLSv1.2", "TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256", 2048, 4},
{"TLSv1.3", "TLS_AES_256_GCM_SHA384", 2048, 0},
{"TLSv1.3", "TLS_AES_256_GCM_SHA384", 2048, 4}

https://github.com/apache/mina/actions/runs/37891283765

Test JDK 17, ubuntu-latest succeeded 2 minutes ago in 15m 10s

Test JDK 17, windows-latest succeeded 13 minutes ago in 4m 49s

Test JDK 17, macos-latest succeeded 12 minutes ago in 5m 11s

I just ran this test on Windows with the old SSLHandlerG1 (without the synchronization fixes), and it succeeded. The test should fail under these conditions.

Moreover, when run on a JDK 8.0.422.5-hotspot, it fails to connect with TLS 1.2 and TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256. With TLS 1.2 and TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 is can connect.

@tomaswolf

I just ran this test on Windows with the old SSLHandlerG1 (without the synchronization fixes), and it succeeded. The test should fail under these conditions.

And it occasionally will succeed. The maximize failure we have to significantly increase iteration count (or for example enabling DEBUG logging helps). I'm not sure if we should increase the count since the build time increased significantly already.

Moreover, when run on a JDK 8.0.422.5-hotspot, it fails to connect with TLS 1.2 and TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256. With TLS 1.2 and TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 is can connect.

I'm assuming this is due to the fact ciphers differ between Java version. Do we want to find a cipher that works for all possible versions (possible?) or just those that are CI configured?

Latest changes pushed as suggested.

With the current setup the build is significantly longer especially on Linux (these environment seem to have some problems in recent days as the delay to start seem to be longer)

{"TLSv1.2", "TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256", 2048, 0},
{"TLSv1.2", "TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256", 2048, 4},
{"TLSv1.3", "TLS_AES_256_GCM_SHA384", 2048, 0},
{"TLSv1.3", "TLS_AES_256_GCM_SHA384", 2048, 4}

https://github.com/apache/mina/actions/runs/37891283765

Test JDK 17, ubuntu-latest succeeded 2 minutes ago in 15m 10s

Test JDK 17, windows-latest succeeded 13 minutes ago in 4m 49s

Test JDK 17, macos-latest succeeded 12 minutes ago in 5m 11s

The time it takes on the GH's CI/CD is not relevant. You can't tell if the VM were started on a heavily loaded server, the build might be faster a few hours later.

If you run the build on your computer and sees a increase, than that would be relevant...

And yes, as there is a synchronized section, it will be slower with the tests we have.

And it occasionally will succeed.

Yes, that's the problem with race conditions. I have no idea how we could provoke hitting it more frequently.

I'm assuming this is due to the fact ciphers differ between Java version. Do we want to find a cipher that works for all possible versions (possible?) or just those that are CI configured?

As part of the release process we will run tests locally, and they must not fail. So yes, we have to find a way to make this work on CI and locally in different configurations. I see two ways:

• check that the cipher is supported before trying to use, and use assumeTrue(cipherIsSupported()). Disadvantage: on a system where none of the test's ciphers are supported, all tests will be skipped.
• or use a commonly supported cipher like TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384.

Assertion logic looks fine now. Thanks a lot! Only issue is the cipher choice for the TLS 1.2 tests. AES/GCM may be more widespread than ChaCha20Poly1305?

Mentally I was insisting on using a single cipher suite for each test, but probably it might be better just to provide a list of cipher suite to avoid conditions (junit assumptions as suggested). Cipher suites are not the issue for this problem (but might have impact in the future).

I was thinking of changing the parameters to:

{"TLSv1.2", "TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384", 2048, 0},
{"TLSv1.2", "TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384", 2048, 4},
{"TLSv1.3", "TLS_AES_128_GCM_SHA256,TLS_AES_256_GCM_SHA384", 2048, 0},
{"TLSv1.3", "TLS_AES_128_GCM_SHA256,TLS_AES_256_GCM_SHA384", 2048, 4},

BTW. Is the Java 8 build even supported? I tried to build it locally using JDK 8 with java-8-compilation and jdk8 profiles enabled and I got

[ERROR] Rule 1: org.apache.maven.enforcer.rules.version.RequireJavaVersion failed with message:
[ERROR] Detected JDK C:\Users\Marcin\.jdks\corretto-1.8.0_504\jre is version 1.8.0-504 which is not in the allowed range [17,).

BTW. Is the Java 8 build even supported? I tried to build it locally using JDK 8 with java-8-compilation and jdk8 profiles enabled and I got

No, we must use Java 17 to build MINA 2.2.X branch:

    <plugins>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-enforcer-plugin</artifactId>
        <executions>
          <execution>
            <id>enforce-maven</id>
            <goals>
              <goal>enforce</goal>
            </goals>
            <configuration>
              <rules>
                <requireMavenVersion>
                  <version>(3.8,]</version>
                </requireMavenVersion>
                <requireJavaVersion>
                  <version>17</version>
                </requireJavaVersion>
              </rules>    
            </configuration>
          </execution>
        </executions>
      </plugin>
    

We have also updated the web site some time ago to be clear about it:

https://mina.apache.org/mina-project/developer-guide.html#checking-out-the-code

However we produce code that is Java 8 compliant:

    <!-- Define the Java source and target version -->
    <maven.compiler.source>8</maven.compiler.source>
    <maven.compiler.target>8</maven.compiler.target>

The pom.xml should be updated to use:

        <plugin>
          <groupId>org.apache.maven.plugins</groupId>
          <artifactId>maven-compiler-plugin</artifactId>
          <version>${version.compiler.plugin}</version>
          <configuration>
            <showDeprecation>true</showDeprecation>
            <encoding>ISO-8859-1</encoding>
            <release>8</release>
            <source>8</source>
            <target>8</target>
          </configuration>
        </plugin>

accordingly to https://maven.apache.org/plugins/maven-compiler-plugin/examples/set-compiler-release.html

Thanks for help and input. I'm glad it is overish... ;)